atelet: emit per-actor usage events from the stats sweep - #1206

docs/observability.md

We can update doc in a separate PR after implementation is finalized and submitted. Otherwise, we will need to maintain sync of implementation and doc which is not very efficient.

Right now the sampleFirst sit in the critical path synchronously

Done in 91e3fff: sampleFirst now samples from its own goroutine on a context.WithoutCancel context — the Run/Restore handlers return immediately, so the resume SLO pays nothing for telemetry, fast path or worst case. The sampler's own 10s timeout still bounds the detached read.

sampleFinal deliberately stays synchronous: its ordering against CheckpointWorkload is the feature (sampling after the dispatch would race the epoch's own end), and the suspend path carries no sub-second SLO. Both doc comments now state this asymmetry, and the tests cover the async emission and that the detached context still carries a deadline.

I would double check with Benjamin Elder (@BenTheElder) to make sure that the synchronous sampling logic in the running -> suspend path is acceptable. (Happy case few ms, but worst case 10s latency?)

(Given the first sampling logic has become async so suspend -> running latency won't be affected)

I would double check with Benjamin Elder (@BenTheElder) to make sure that the synchronous sampling logic in the running -> suspend path is acceptable. (Happy case few ms, but worst case 10s latency?)

Yikes, 10s in the hot path is way outside of our targets, what other options did we consider?

I would double check with Benjamin Elder (@BenTheElder) to make sure that the synchronous sampling logic in the running -> suspend path is acceptable. (Happy case few ms, but worst case 10s latency?)

Yikes, 10s in the hot path is way outside of our targets, what other options did we consider?

The final sample has to be a blocking call, otherwise, it potentially gets lost forever (cgroup got destroyed). However, we can decrease the lifecycleSampleTimeout to 1s or even less. For the happy case, it should only take X milliseconds.

The final sample has to be a blocking call, otherwise, it potentially gets lost forever (cgroup got destroyed). However, we can decrease the lifecycleSampleTimeout to 1s or even less. For the happy case, it should only take X milliseconds.

So in theory we want say, 100ms, but realistically we are something at least XXXms for gVisor operations, and slower for uVM at the moment. Slowing that down in any way is going the wrong direction as we're already pretty far from the desired latency.

Can we just sample while it's online and not sample during snapshot etc.

The final sample has to be a blocking call, otherwise, it potentially gets lost forever (cgroup got destroyed). However, we can decrease the lifecycleSampleTimeout to 1s or even less. For the happy case, it should only take X milliseconds.

So in theory we want say, 100ms, but realistically we are something at least XXXms for gVisor operations, and slower for uVM at the moment. Slowing that down in any way is going the wrong direction as we're already pretty far from the desired latency.

Can we just sample while it's online and not sample during snapshot etc.

The periodic resource event emission during normal operation has already been implemented in this PR. However, the final resource utilization event is very important before actor suspend. This event contains the metric of total CPU usage of current actor session. The periodic resource event is unable to provide this information accurately.

Alternatively, we can make this operation async (best effort) so that it does not block the hot path. WDYT?

I don't think async works here. The whole point of the final sample is that it reads the CPU counter before the checkpoint destroys it. If we fire-and-forget, the read races the teardown and loses most of the time, so we'd ship the feature with its main guarantee broken.

Correct me if I am wrong, but I think we don't have to choose between latency and the sample. The Checkpoint handler already does a bunch of prep before dispatching to the ateom (read sandbox record, ensure assets, dial, build spec). We can start the sample in a goroutine at the top of the handler and join it right before dispatch. The read takes single-digit ms and the prep takes way longer, so in the happy case it's already done by the time we need it with zero added latency, not just "small". If it's somehow still not done at dispatch time, we wait a short grace (say 50ms), then log the lost-sample warning and proceed. So the worst case drops from 10s to 50ms, and only when the stats path is already broken.

Longer term the clean fix is to have ateom take the sample itself as the first step of CheckpointWorkload and return it in the response, that's literally "sample while it's online" with zero added latency and no race at all. But it's a proto change touching both runtimes, so I'd do that as a follow-up.

WDYT about overlap + short grace in this PR, piggyback as follow-up?

I don't think async works here. The whole point of the final sample is that it reads the CPU counter before the checkpoint destroys it. If we fire-and-forget, the read races the teardown and loses most of the time, so we'd ship the feature with its main guarantee broken.

Correct me if I am wrong, but I think we don't have to choose between latency and the sample. The Checkpoint handler already does a bunch of prep before dispatching to the ateom (read sandbox record, ensure assets, dial, build spec). We can start the sample in a goroutine at the top of the handler and join it right before dispatch. The read takes single-digit ms and the prep takes way longer, so in the happy case it's already done by the time we need it with zero added latency, not just "small". If it's somehow still not done at dispatch time, we wait a short grace (say 50ms), then log the lost-sample warning and proceed. So the worst case drops from 10s to 50ms, and only when the stats path is already broken.

Longer term the clean fix is to have ateom take the sample itself as the first step of CheckpointWorkload and return it in the response, that's literally "sample while it's online" with zero added latency and no race at all. But it's a proto change touching both runtimes, so I'd do that as a follow-up.

WDYT about overlap + short grace in this PR, piggyback as follow-up?

The overlap with a short grace period makes sense to me, but I have reservations about the long-term approach. I considered moving the final sampling to ateom before; however, if our goal is zero overhead on checkpoint operations, blocking the process to collect metrics will inevitably introduce latency—regardless of whether it's handled in atelet via a dedicated RPC or embedded directly into the checkpoint RPC via ateom.

I don't think async works here. The whole point of the final sample is that it reads the CPU counter before the checkpoint destroys it. If we fire-and-forget, the read races the teardown and loses most of the time, so we'd ship the feature with its main guarantee broken.
Correct me if I am wrong, but I think we don't have to choose between latency and the sample. The Checkpoint handler already does a bunch of prep before dispatching to the ateom (read sandbox record, ensure assets, dial, build spec). We can start the sample in a goroutine at the top of the handler and join it right before dispatch. The read takes single-digit ms and the prep takes way longer, so in the happy case it's already done by the time we need it with zero added latency, not just "small". If it's somehow still not done at dispatch time, we wait a short grace (say 50ms), then log the lost-sample warning and proceed. So the worst case drops from 10s to 50ms, and only when the stats path is already broken.
Longer term the clean fix is to have ateom take the sample itself as the first step of CheckpointWorkload and return it in the response, that's literally "sample while it's online" with zero added latency and no race at all. But it's a proto change touching both runtimes, so I'd do that as a follow-up.
WDYT about overlap + short grace in this PR, piggyback as follow-up?

The overlap with a short grace period makes sense to me, but I have reservations about the long-term approach. I considered moving the final sampling to ateom before; however, if our goal is zero overhead on checkpoint operations, blocking the process to collect metrics will inevitably introduce latency—regardless of whether it's handled in atelet via a dedicated RPC or embedded directly into the checkpoint RPC via ateom.

One thing that hasn't come up in this thread: the latency question aside, there's a correctness bug in the current ordering that the ateom approach would fix for free. Right now we emit the final sample before calling CheckpointWorkload. If the checkpoint fails transiently, the workload keeps running and the control plane retries so we emit a second final for the same session. Anyone summing finals now double counts almost the whole session, and the events carry no epoch/attempt id to dedup on.

If ateom takes the sample as part of CheckpointWorkload and returns it in the response, this problem can't happen: we only emit when the checkpoint actually succeeded, so it's always exactly one final per session. Same trick would work for Terminate, which currently emits no final at all.

So I'd frame the follow-up as a correctness fix, not a latency optimization. On the latency concern: the read is cheap on gVisor, and ateom can overlap it with its own pre-destructive prep, same as what we're doing here. So it doesn't have to add anything to the critical path.

I don't think async works here. The whole point of the final sample is that it reads the CPU counter before the checkpoint destroys it. If we fire-and-forget, the read races the teardown and loses most of the time, so we'd ship the feature with its main guarantee broken.
Correct me if I am wrong, but I think we don't have to choose between latency and the sample. The Checkpoint handler already does a bunch of prep before dispatching to the ateom (read sandbox record, ensure assets, dial, build spec). We can start the sample in a goroutine at the top of the handler and join it right before dispatch. The read takes single-digit ms and the prep takes way longer, so in the happy case it's already done by the time we need it with zero added latency, not just "small". If it's somehow still not done at dispatch time, we wait a short grace (say 50ms), then log the lost-sample warning and proceed. So the worst case drops from 10s to 50ms, and only when the stats path is already broken.
Longer term the clean fix is to have ateom take the sample itself as the first step of CheckpointWorkload and return it in the response, that's literally "sample while it's online" with zero added latency and no race at all. But it's a proto change touching both runtimes, so I'd do that as a follow-up.
WDYT about overlap + short grace in this PR, piggyback as follow-up?

The overlap with a short grace period makes sense to me, but I have reservations about the long-term approach. I considered moving the final sampling to ateom before; however, if our goal is zero overhead on checkpoint operations, blocking the process to collect metrics will inevitably introduce latency—regardless of whether it's handled in atelet via a dedicated RPC or embedded directly into the checkpoint RPC via ateom.

One thing that hasn't come up in this thread: the latency question aside, there's a correctness bug in the current ordering that the ateom approach would fix for free. Right now we emit the final sample before calling CheckpointWorkload. If the checkpoint fails transiently, the workload keeps running and the control plane retries so we emit a second final for the same session. Anyone summing finals now double counts almost the whole session, and the events carry no epoch/attempt id to dedup on.

If ateom takes the sample as part of CheckpointWorkload and returns it in the response, this problem can't happen: we only emit when the checkpoint actually succeeded, so it's always exactly one final per session. Same trick would work for Terminate, which currently emits no final at all.

So I'd frame the follow-up as a correctness fix, not a latency optimization. On the latency concern: the read is cheap on gVisor, and ateom can overlap it with its own pre-destructive prep, same as what we're doing here. So it doesn't have to add anything to the critical path.

Updated in the latest commits — the final sample now follows the overlap shape proposed above, tightened one step further:

• beginFinalSample starts the read at the top of the Checkpoint handler, so it runs concurrently with the handler's own prep (sandbox record, asset ensure, dial, spec build) and is done long before it's needed.
• joinBeforeCheckpoint runs immediately before dispatching CheckpointWorkload: it waits at most 50ms, and a read still in flight is cancelled, not left racing the teardown. By dispatch time the sample is deterministically complete or abandoned — never pending.
• emitAfterSuccess publishes only once the ateom confirms the checkpoint. This also fixes an ordering bug in the previous revision: a transiently failed, retried checkpoint would have emitted a duplicate final per attempt, double-counting the session for anyone summing finals. Now every session gets exactly one final, from the attempt that succeeded.

Net latency: zero added in the happy case; worst case 50ms, paid only when the stats path is already broken. The read timeout (500ms) bounds only a background goroutine, never the handler.

On the ateom-side follow-up: with emit-on-success in atelet, the duplicate-final correctness issue is fixed here, so what the proto change would still buy is exact-at-freeze accuracy (the current design undercounts by the CPU burned between read and freeze — prep-length on a session-length measurement) and dropping the 50ms grace. The Terminate gap doesn't need it either: the same begin/join/emit pattern fits the Terminate handler as a small follow-up.

Updated the PR, removed the lifecycle event and only keep periodic ones.

One robustness concern: emit writes to stdout synchronously inside the sweep's errgroup, and a write to a full pipe blocks forever, since there's no timeout on stdout writes. So if the log consumer stalls (disk full, log rotation stuck), one stuck write wedges g.Wait(), the tick loop stops, and the metrics freeze too. They'll keep re-serving the last snapshot with no error. Before this PR the sweep never wrote to stdout, so log-pipe health and metric health were independent; this couples them, and it bites exactly during disk incidents when you'd be looking at these dashboards.

Suggestion: make the emitter non-blocking. A small bounded channel drained by one writer goroutine, dropping and counting when full, would do it. Dropping is safe here since these are cumulative samples: the next healthy tick repairs the gap. Losing events when stdout is dead is unavoidable anyway; losing the metrics with them isn't.

Suggestion: make the emitter non-blocking. A small bounded channel drained by one writer goroutine, dropping and counting when full, would do it.

Done in 32549be, as suggested: emit now writes through an asyncWriter — bounded queue (256 records, sized to a sweep's burst), one drain goroutine, select-with-default on the way in so the sweep can never block on the pipe. Drops are counted and reported in one warning on the first successful write afterwards, i.e. once the stream has proven itself live enough for the warning to actually land. That restores the pre-PR invariant that the sweep performs no operation that can wait on the log consumer — events degrade to drop-and-count (the next healthy tick re-samples), and the metrics keep their independent OTLP path through a stall.

Tests cover the contract directly: a wedged underlying writer with a burst past capacity (every write returns immediately, drop count exact, everything not dropped drains on recovery — conservation-checked) and that queued records are copies, since slog reuses its buffer.

The async queue fixes blocking, but the logger and this drain goroutine are still two uncoordinated writers on stdout. Today that works only because every record stays under PIPE_BUF (4 KB), which is an accident of current field sizes, not a guarantee. Add a field or point stdout at a file and lines can tear.

Suggest wrapping stdout in actorlog.NewSyncedWriter once, handing it to serverboot.InitLoggerWithWriter and to newAsyncWriter, the same way ateom-gvisor and ateom-microvm already do. The queue keeps the sweep off the critical path, and the lock makes interleaving impossible regardless of size or destination.

Suggest wrapping stdout in actorlog.NewSyncedWriter once, handing it to serverboot.InitLoggerWithWriter and to newAsyncWriter, the same way ateom-gvisor and ateom-microvm already do.

Done in 0fc0089, exactly as suggested: main builds one actorlog.NewSyncedWriter(os.Stdout) and hands it to both serverboot.InitLoggerWithWriter and newAsyncWriter. You're right that the previous arrangement was tear-free only by the accident of records fitting PIPE_BUF — the comment claiming single-Write safety is gone with it. One nuance for the record: this doesn't reintroduce the blocking hazard the asyncWriter removed — under a wedged pipe the drain goroutine blocks on the mutex, but the sweep stays behind the queue exactly as before; the lock only guarantees whole records while both channels are live.

Same commit closes a related asymmetry you'd have found next: the drop report was routed through the leveled logger, so --log-level=error would have silenced the only evidence of data loss while the feed itself survived. It now rides the emitter's fixed-level pipeline over the same sink — the loss signal is as unkillable as the feed it reports on (still WARN on the wire, so severity-based alerting is unaffected). The recovery-drain test asserts the report arrives.

Could you update docs/observability.md in the logging section to include instructions for using the new per-actor usage events?

Done, as the separate PR discussed above now that the implementation has settled: #1559 adds a Per-Actor Usage Events section to the logging guide — example record, query recipe on the shared label group, per-field semantics (including the epoch scoping of memory_peak_bytes/cpu_usage_usec per source), the sampling knob and delivery contract, and the log-based-metric cardinality rule — plus cross-links from the metrics section. PTAL Jeff Luo (@JeffLuoo)